benchmark each phase of request processing #1009

graphaelli · 2018-06-14T18:54:55Z

for comparison with #1000, looking for a baseline of the validation/decoding/transform cycle for each processor:

Results for TestProcessErrorFrontendMinifiedSmapProcessRequest are surprising. Complete results from a quick run below.

$ go test -benchmem -run=XXX -benchtime=100ms -bench='.*Processor$' ./processor/...
PASS
ok  	github.com/elastic/apm-server/processor	0.025s
PASS
ok  	github.com/elastic/apm-server/processor/error	0.022s
goos: darwin
goarch: amd64
pkg: github.com/elastic/apm-server/processor/error/package_tests
BenchmarkBackendProcessor/TestProcessErrorMinimalServiceValidate-8         	   20000	      7456 ns/op	     225 B/op	       8 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalServiceDecode-8           	   50000	      3769 ns/op	     504 B/op	      10 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalServiceTransform-8        	   20000	      6699 ns/op	    3280 B/op	      38 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalServiceProcessRequest-8   	   10000	     16385 ns/op	    4011 B/op	      56 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalProcessValidate-8         	   20000	      9533 ns/op	     402 B/op	      14 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalProcessDecode-8           	   30000	      4284 ns/op	     568 B/op	      12 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalProcessTransform-8        	   20000	      6931 ns/op	    3616 B/op	      41 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalProcessProcessRequest-8   	   10000	     19496 ns/op	    4571 B/op	      67 allocs/op
BenchmarkBackendProcessor/TestProcessErrorFullValidate-8                   	    2000	     62771 ns/op	   13105 B/op	     162 allocs/op
BenchmarkBackendProcessor/TestProcessErrorFullDecode-8                     	   10000	     13014 ns/op	    3632 B/op	      93 allocs/op
BenchmarkBackendProcessor/TestProcessErrorFullTransform-8                  	    5000	     36763 ns/op	   16913 B/op	     207 allocs/op
BenchmarkBackendProcessor/TestProcessErrorFullProcessRequest-8             	    2000	    115515 ns/op	   33643 B/op	     462 allocs/op
BenchmarkBackendProcessor/TestProcessErrorNullValuesValidate-8             	    5000	     38172 ns/op	   11105 B/op	      93 allocs/op
BenchmarkBackendProcessor/TestProcessErrorNullValuesDecode-8               	   20000	      7059 ns/op	    1184 B/op	      22 allocs/op
BenchmarkBackendProcessor/TestProcessErrorNullValuesTransform-8            	   10000	     17867 ns/op	    7840 B/op	      87 allocs/op
BenchmarkBackendProcessor/TestProcessErrorNullValuesProcessRequest-8       	    2000	     65043 ns/op	   20133 B/op	     202 allocs/op
BenchmarkBackendProcessor/TestProcessErrorAugmentedIPValidate-8            	   20000	      7805 ns/op	     227 B/op	       8 allocs/op
BenchmarkBackendProcessor/TestProcessErrorAugmentedIPDecode-8              	   30000	      4175 ns/op	     600 B/op	      15 allocs/op
BenchmarkBackendProcessor/TestProcessErrorAugmentedIPTransform-8           	   20000	      7635 ns/op	    3344 B/op	      42 allocs/op
BenchmarkBackendProcessor/TestProcessErrorAugmentedIPProcessRequest-8      	   10000	     17636 ns/op	    4172 B/op	      65 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadExceptionValidate-8         	   50000	      3688 ns/op	       0 B/op	       0 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadExceptionDecode-8           	   50000	      2741 ns/op	     520 B/op	       9 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadExceptionTransform-8        	   20000	      6296 ns/op	    2976 B/op	      36 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadExceptionProcessRequest-8   	   10000	     11955 ns/op	    3496 B/op	      45 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadLogValidate-8               	   30000	      5520 ns/op	     225 B/op	       8 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadLogDecode-8                 	   50000	      2665 ns/op	     488 B/op	       9 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadLogTransform-8              	   20000	      6303 ns/op	    2976 B/op	      36 allocs/op
BenchmarkBackendProcessor/TestProcessErrorMinimalPayloadLogProcessRequest-8         	   10000	     13165 ns/op	    3691 B/op	      53 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendValidate-8                       	    5000	     21814 ns/op	    1975 B/op	      72 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendDecode-8                         	   20000	      7911 ns/op	    2528 B/op	      57 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendTransform-8                      	     200	    715452 ns/op	  145032 B/op	     752 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendProcessRequest-8                 	     200	    755787 ns/op	  149524 B/op	     881 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendNoSmapValidate-8                 	   10000	     20338 ns/op	    1718 B/op	      61 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendNoSmapDecode-8                   	   20000	      7139 ns/op	    2088 B/op	      44 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendNoSmapTransform-8                	     300	    564908 ns/op	  120392 B/op	     714 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendNoSmapProcessRequest-8           	     200	    603226 ns/op	  124191 B/op	     819 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapValidate-8           	    5000	     32266 ns/op	    4561 B/op	     105 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapDecode-8             	   20000	      8474 ns/op	    2680 B/op	      56 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapTransform-8          	       5	  32428438 ns/op	10618275 B/op	    9291 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapProcessRequest-8     	       3	  33519224 ns/op	10625853 B/op	    9453 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorAugmentedUserAgentAndIPValidate-8        	   20000	      7626 ns/op	     227 B/op	       8 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorAugmentedUserAgentAndIPDecode-8          	   30000	      4080 ns/op	     568 B/op	      12 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorAugmentedUserAgentAndIPTransform-8       	   20000	      6848 ns/op	    3008 B/op	      38 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorAugmentedUserAgentAndIPProcessRequest-8  	   10000	     16972 ns/op	    3804 B/op	      58 allocs/op
PASS
ok  	github.com/elastic/apm-server/processor/error/package_tests	62.474s
PASS
ok  	github.com/elastic/apm-server/processor/healthcheck	0.018s
PASS
ok  	github.com/elastic/apm-server/processor/sourcemap	0.020s
PASS
ok  	github.com/elastic/apm-server/processor/sourcemap/package_tests	0.021s
PASS
ok  	github.com/elastic/apm-server/processor/transaction	0.024s
goos: darwin
goarch: amd64
pkg: github.com/elastic/apm-server/processor/transaction/package_tests
BenchmarkBackendProcessor/TestProcessTransactionFullValidate-8         	    2000	     93496 ns/op	   29147 B/op	     347 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionFullDecode-8           	   10000	     13823 ns/op	    3048 B/op	      92 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionFullTransform-8        	    3000	     41092 ns/op	   24473 B/op	     237 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionFullProcessRequest-8   	    1000	    147752 ns/op	   56678 B/op	     676 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionNullValuesValidate-8   	    3000	     54666 ns/op	   12888 B/op	     143 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionNullValuesDecode-8     	   10000	     10445 ns/op	    1832 B/op	      36 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionNullValuesTransform-8  	    5000	     24000 ns/op	   14640 B/op	     137 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionNullValuesProcessRequest-8         	    2000	     93324 ns/op	   29363 B/op	     316 allocs/op
BenchmarkBackendProcessor/TestProcessSystemNullValidate-8                          	   20000	      8628 ns/op	     225 B/op	       6 allocs/op
BenchmarkBackendProcessor/TestProcessSystemNullDecode-8                            	   50000	      3729 ns/op	     504 B/op	       9 allocs/op
BenchmarkBackendProcessor/TestProcessSystemNullTransform-8                         	   30000	      5953 ns/op	    3896 B/op	      45 allocs/op
BenchmarkBackendProcessor/TestProcessSystemNullProcessRequest-8                    	   10000	     17352 ns/op	    4627 B/op	      60 allocs/op
BenchmarkBackendProcessor/TestProcessProcessNullValidate-8                         	   20000	      8638 ns/op	     225 B/op	       6 allocs/op
BenchmarkBackendProcessor/TestProcessProcessNullDecode-8                           	   50000	      3699 ns/op	     504 B/op	       9 allocs/op
BenchmarkBackendProcessor/TestProcessProcessNullTransform-8                        	   30000	      5901 ns/op	    3896 B/op	      45 allocs/op
BenchmarkBackendProcessor/TestProcessProcessNullProcessRequest-8                   	   10000	     17454 ns/op	    4627 B/op	      60 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalSpanValidate-8              	   10000	     11602 ns/op	     674 B/op	      20 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalSpanDecode-8                	   30000	      4602 ns/op	     656 B/op	      14 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalSpanTransform-8             	   20000	      8266 ns/op	    5736 B/op	      60 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalSpanProcessRequest-8        	   10000	     23183 ns/op	    7069 B/op	      94 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalServiceValidate-8           	   20000	      8328 ns/op	     225 B/op	       6 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalServiceDecode-8             	   50000	      3684 ns/op	     520 B/op	      10 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalServiceTransform-8          	   20000	      6332 ns/op	    4200 B/op	      47 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalServiceProcessRequest-8     	   10000	     17635 ns/op	    4947 B/op	      63 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalProcessValidate-8           	   20000	      9906 ns/op	     401 B/op	      12 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalProcessDecode-8             	   30000	      4210 ns/op	     584 B/op	      12 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalProcessTransform-8          	   20000	      6599 ns/op	    4552 B/op	      50 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalProcessProcessRequest-8     	   10000	     19876 ns/op	    5524 B/op	      74 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionEmptyValidate-8                    	   20000	      8762 ns/op	     225 B/op	       6 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionEmptyDecode-8                      	   50000	      3737 ns/op	     520 B/op	      10 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionEmptyTransform-8                   	   20000	      5942 ns/op	    3912 B/op	      46 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionEmptyProcessRequest-8              	   10000	     17566 ns/op	    4659 B/op	      62 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionAugmentedIPValidate-8              	   20000	      8305 ns/op	     225 B/op	       6 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionAugmentedIPDecode-8                	   50000	      3905 ns/op	     552 B/op	      11 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionAugmentedIPTransform-8             	   20000	      6202 ns/op	    4248 B/op	      48 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionAugmentedIPProcessRequest-8        	   10000	     17749 ns/op	    5027 B/op	      65 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalPayloadValidate-8           	   20000	      6616 ns/op	     225 B/op	       6 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalPayloadDecode-8             	   50000	      2638 ns/op	     504 B/op	       9 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalPayloadTransform-8          	   30000	      5852 ns/op	    3896 B/op	      45 allocs/op
BenchmarkBackendProcessor/TestProcessTransactionMinimalPayloadProcessRequest-8     	   10000	     14145 ns/op	    4627 B/op	      60 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionFrontendValidate-8                	   10000	     13310 ns/op	     870 B/op	      32 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionFrontendDecode-8                  	   30000	      5146 ns/op	    1280 B/op	      28 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionFrontendTransform-8               	   10000	     17945 ns/op	    7528 B/op	     122 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionFrontendProcessRequest-8          	    5000	     36495 ns/op	    9666 B/op	     182 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedMergeValidate-8          	   20000	      7582 ns/op	     227 B/op	       6 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedMergeDecode-8            	   50000	      2953 ns/op	     584 B/op	      12 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedMergeTransform-8         	   20000	      6589 ns/op	    3928 B/op	      47 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedMergeProcessRequest-8    	   10000	     16663 ns/op	    4741 B/op	      65 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedValidate-8               	   20000	      7160 ns/op	     225 B/op	       6 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedDecode-8                 	   50000	      2916 ns/op	     584 B/op	      12 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedTransform-8              	   20000	      6556 ns/op	    4600 B/op	      51 allocs/op
BenchmarkFrontendProcessor/TestProcessTransactionAugmentedProcessRequest-8         	   10000	     15989 ns/op	    5412 B/op	      69 allocs/op
PASS
ok  	github.com/elastic/apm-server/processor/transaction/package_tests	83.360s

BenchmarkEventFileLoadingOnce in the processor/error panics anyway

jalvz · 2018-06-15T07:59:42Z

The slow benchmarks are due to this:
https://github.com/graphaelli/apm-server/blob/ae79ae0f00f902b5b21c94bd81c0430645dcb3a2/processor/error/package_tests/processor_test.go#L75

does not work for some reason

graphaelli · 2018-06-15T14:30:20Z

Thanks for tracking that down @jalvz , updated results:

BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapValidate-8         	    5000	     33951 ns/op	    4560 B/op	     105 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapDecode-8           	   20000	      8171 ns/op	    2680 B/op	      56 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapTransform-8        	    2000	     75172 ns/op	   28395 B/op	     426 allocs/op
BenchmarkFrontendProcessor/TestProcessErrorFrontendMinifiedSmapProcessRequest-8   	    2000	    123255 ns/op	   35638 B/op	     587 allocs/op

* benchmark each phase of request processing * remove now redundant benchmarks BenchmarkEventFileLoadingOnce in the processor/error panics anyway * cache sourcemap fetch when benchmarking

graphaelli added 2 commits June 14, 2018 14:52

benchmark each phase of request processing

ae79ae0

remove now redundant benchmarks

86964ce

BenchmarkEventFileLoadingOnce in the processor/error panics anyway

graphaelli requested review from jalvz and simitt June 14, 2018 19:37

jalvz approved these changes Jun 15, 2018

View reviewed changes

try to exclude Fetch from benchmark

203c548

does not work for some reason

cache sourcemap fetch when benchmarking

5d20f70

graphaelli force-pushed the bench-process-request branch from e59f14f to 5d20f70 Compare June 15, 2018 14:37

graphaelli merged commit 291cc8f into elastic:master Jun 18, 2018

graphaelli deleted the bench-process-request branch June 18, 2018 22:30

simitt mentioned this pull request Jul 4, 2018

[6.x] multiple backports #1067

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

benchmark each phase of request processing #1009

benchmark each phase of request processing #1009

Uh oh!

graphaelli commented Jun 14, 2018

Uh oh!

jalvz commented Jun 15, 2018

Uh oh!

graphaelli commented Jun 15, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

benchmark each phase of request processing #1009

benchmark each phase of request processing #1009

Uh oh!

Conversation

graphaelli commented Jun 14, 2018

Uh oh!

jalvz commented Jun 15, 2018

Uh oh!

graphaelli commented Jun 15, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants